Enable guest tracing #695

dblnz · 2025-07-07T15:53:09Z

Description

This PR updates the work @syntactically has done in #103 to latest main and extends it to support tracing the guest for performance.
This effort is part of the #669 issue.
Improvements on the trace file output will be addressed in #704 .

How it works

It defines a TraceBuffer in the guest that holds TraceRecords. These records are only sent to the host when the buffer gets full, or an exit (Out/Halt instructions) is anticipated.
The records are sent to the host using an Out instruction and providing the pointer to an array of TraceRecords.
The host accesses the guest memory, reads these records and writes them to the trace file.

The guest uses the Invariant TSC and rdtsc instruction to read the clock cycles in the guest and calculate the timestamp on the host.
The timestamp is relative to when the TraceInfo started (before creating the Hypervisor Driver in this case).

Two additional crates define the guest logic for tracing. One defines some macros meant to make the annotation of functions simpler to the user

#[hyperlight_guest_tracing_macro::trace_function]
fn function_to_trace() {}

Note: The data processing could be improved (maybe OTEL), I've just used what we had at hand.

Results

Below are some results I have generated based on our hello-world example in the hyperlight repository.

1. My host machine on WSL2 running KVM on Intel(R) Core(TM) Ultra 7 165H

Has Invariant TSC

[338µs    ] BLAKE3 hash of binary is 05e1c8a51d535507af833a5f4e5e4033a42f4e395cdba4cfe7453dcffe3ea76d
[58.197ms ] > entrypoint
[58.294ms ]   > load_gdt
[58.314ms ]   < load_gdt
[58.314ms ]   > load_idt
[58.328ms ]     > init_idt
[58.356ms ]     < init_idt
[58.356ms ]   < load_idt
[58.44ms  ]   hyperlight_main
[58.574ms ] > halt
[59.385ms ] > dispatch_function
[59.386ms ]   > internal_dispatch_function
[59.408ms ]     > try_pop_shared_input_data_into
[59.423ms ]       Start converting buffer
[59.566ms ]       Finish converting buffer
[59.567ms ]     < try_pop_shared_input_data_into
[59.567ms ]     > call_guest_function
[59.567ms ]       Calling guest function
[59.628ms ]       > call_host_function
[59.628ms ]         > call_host_function_without_returning_result
[59.671ms ]           > push_shared_output_data
[59.683ms ]             Start copy of data
[59.683ms ]             Finish copy of data
[59.683ms ]           < push_shared_output_data
[59.683ms ]           > out32
[60.936ms ]           < out32
[60.936ms ]         < call_host_function_without_returning_result
[60.937ms ]         > get_host_return_value
[61.002ms ]           > try_pop_shared_input_data_into
[61.002ms ]             Start converting buffer
[61.046ms ]             Finish converting buffer
[61.046ms ]           < try_pop_shared_input_data_into
[61.046ms ]         < get_host_return_value
[61.046ms ]       < call_host_function
[61.05ms  ]     < call_guest_function
[61.05ms  ]     > push_shared_output_data
[61.05ms  ]       Start copy of data
[61.05ms  ]       Finish copy of data
[61.05ms  ]     < push_shared_output_data
[61.05ms  ]   < internal_dispatch_function
[61.051ms ] > halt

2. Azure VM running mshv3 on AMD EPYC 7763 64-Core Processor

Does not report an invariant TSC. I am currently investigating if I can get an Azure VM that reports supporting an invariant TSC.

[67µs     ] BLAKE3 hash of binary is 56561e9811e4a1907f2883cf34345cab6e48ad444201d8a9678860f46749dd41
[941µs    ] > entrypoint
[943µs    ]   > load_gdt
[943µs    ]   < load_gdt
[943µs    ]   > load_idt
[943µs    ]     > init_idt
[944µs    ]     < init_idt
[944µs    ]   < load_idt
[945µs    ]   hyperlight_main
[956µs    ] > halt
[1.431ms  ] > dispatch_function
[1.446ms  ]   > internal_dispatch_function
[1.446ms  ]     > try_pop_shared_input_data_into
[1.446ms  ]       Start converting buffer
[1.448ms  ]       Finish converting buffer
[1.448ms  ]     < try_pop_shared_input_data_into
[1.448ms  ]     > call_guest_function
[1.449ms  ]       Calling guest function
[1.45ms   ]       > call_host_function
[1.45ms   ]         > call_host_function_without_returning_result
[1.452ms  ]           > push_shared_output_data
[1.453ms  ]             Start copy of data
[1.453ms  ]             Finish copy of data
[1.453ms  ]           < push_shared_output_data
[1.453ms  ]           > out32
[1.908ms  ]           < out32
[1.908ms  ]         < call_host_function_without_returning_result
[1.909ms  ]         > get_host_return_value
[1.909ms  ]           > try_pop_shared_input_data_into
[1.909ms  ]             Start converting buffer
[1.91ms   ]             Finish converting buffer
[1.91ms   ]           < try_pop_shared_input_data_into
[1.91ms   ]         < get_host_return_value
[1.91ms   ]       < call_host_function
[1.912ms  ]     < call_guest_function
[1.912ms  ]     > push_shared_output_data
[1.912ms  ]       Start copy of data
[1.913ms  ]       Finish copy of data
[1.913ms  ]     < push_shared_output_data
[1.913ms  ]   < internal_dispatch_function
[1.913ms  ] > halt

TODO

For now, the timestamp of the traces is not calculated correctly. It needs to be calculated relative to the start of the guest and base of on the invariant TSC frequency.
Check the features introduced in the crates to ensure consistency
Expand dump_trace functionality to visualize the traces
Investigate invariant TSC not being correctly reported in Azure VMs.

dblnz · 2025-07-09T14:43:00Z

The output data should be changed to something that other tools can open #704.

syntactically · 2025-07-09T21:39:35Z

Does not report an invariant TSC. I am currently investigating if I can get an Azure VM that reports supporting an invariant TSC.

Just to document this: it was confirmed that the host under a nested MSHV will incorrectly not see the invariant TSC bit, and this should be ignored; on the azure platforms, at least, the TSC is in fact invariant.

jsturtevant

Great work! Could we add a step where the test binaries are executing in the CI pipeline? Right now it looks like none of this code is being exercised since it is all behind feature flag.

docs/hyperlight-metrics-logs-and-traces.md

src/hyperlight_common/Cargo.toml

src/hyperlight_guest/src/exit.rs

src/hyperlight_guest_bin/src/guest_function/call.rs

src/hyperlight_guest_tracing_macro/src/lib.rs

src/hyperlight_host/src/mem/shared_mem.rs

src/hyperlight_host/src/sandbox/outb.rs

src/hyperlight_host/src/sandbox/mod.rs

In the future, the outb handler will need to take a Hypervisor instance in order to be able to access register and memory state of the VM, so it doesn't make sense for these interfaces to be more public than the `Hypervisor` trait. Nobody outside of Hyperlight seems to use these at the moment, so it's probably simplest to restrict these to `pub(crate)`. Signed-off-by: Lucy Menon <[email protected]>

This adds (unused) support for creating trace files for sandboxes and passing them around to relevant sandbox event handler code. This will be used for collecting debug trace and profiling information. Signed-off-by: Lucy Menon <[email protected]> Signed-off-by: Doru Blânzeanu <[email protected]>

This will be useful in the near future, when it will allow transforming the exe_info into unwind information without an extra copy. Signed-off-by: Lucy Menon <[email protected]>

This adds a new interface which tracing code can use to request the values of registers from the hypervisor supervising a sandbox. Signed-off-by: Lucy Menon <[email protected]>

Signed-off-by: Lucy Menon <[email protected]> Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

This allows for producing profiles of memory usage. Signed-off-by: Lucy Menon <[email protected]> Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Lucy Menon <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

syntactically

This looks great! I left a few relatively minor comments/questions inline.

I had one other question about a commit message, so I couldn't put it in the diff comments: in d3c416c, what does the commit message mean by "the Hypervisor checks for the frame Id, to verify what type of exit it is"?

src/hyperlight_guest_bin/src/exceptions/handler.rs

.github/workflows/dep_rust.yml

src/hyperlight_guest/src/exit.rs

src/hyperlight_guest_tracing_macro/src/lib.rs

src/hyperlight_guest_tracing/src/lib.rs

src/trace_dump/main.rs

src/hyperlight_host/src/hypervisor/hyperv_linux.rs

src/hyperlight_host/src/sandbox/outb.rs

src/hyperlight_guest_tracing_macro/src/lib.rs

src/trace_dump/main.rs

dblnz · 2025-07-22T07:29:00Z

This looks great! I left a few relatively minor comments/questions inline.

I had one other question about a commit message, so I couldn't put it in the diff comments: in d3c416c, what does the commit message mean by "the Hypervisor checks for the frame Id, to verify what type of exit it is"?

My phrasing could be better, but I was referring to the OutBAction type, that can be a TraceRecord, TraceMemoryFree, TraceMemoryAlloc or a TraceRecordStack in the context of the tracing.
I'll rephrase when I address the comments you left

syntactically

This is looking really good, thanks!

Please squash the fixup commits (e825f6e onwards) into the original commits for the relevant things before merging.

src/hyperlight_guest_tracing/src/lib.rs

Signed-off-by: Doru Blânzeanu <[email protected]>

…ords - `hyperlight-guest-tracing` defines a `TraceBuffer` that keeps `TraceRecord`s that the guest issues. When the buffer capacity is reached, it automatically issues an `Out` instruction with the corresponding info for the host to retrieve the buffer. - The guest can issue `TraceRecord`s by using the `hyperlight-guest-tracing-macro` crate that pushes new records to the buffer. - `hyperlight_common` contains the definitions for the frame types a guest can send to the host using the `Out` instruction. Signed-off-by: Doru Blânzeanu <[email protected]>

- When an `Out` instruction is intercepted, the Hypervisor checks for the port to verifies what type of exit was encoded. Based on this, when a trace record type is received, we copy the array of trace records from the guest's memory, calculate the timestamp based on the cycles returned by the guest's RDTSC and write the record to the trace file. Signed-off-by: Doru Blânzeanu <[email protected]>

- Add traces wherever we think it might be of use to help us better profile the codebase. - Add flush instructions before halting or running an `OutB` instruction to ensure the records are sent before the guest exits due to an error or a normal exit Signed-off-by: Doru Blânzeanu <[email protected]>

- Update CI to test the tracing functionality - Add features for the Justfile to be able to build guests with features Signed-off-by: Doru Blânzeanu <[email protected]>

Signed-off-by: Doru Blânzeanu <[email protected]>

syntactically

LGTM

dblnz force-pushed the guest-tracing branch from 9930979 to 9d59c0b Compare July 7, 2025 16:40

dblnz added the kind/enhancement For PRs adding features, improving functionality, docs, tests, etc. label Jul 7, 2025

dblnz force-pushed the guest-tracing branch 6 times, most recently from 15f9623 to 030a019 Compare July 9, 2025 12:42

syntactically mentioned this pull request Jul 9, 2025

Component benchmarks hyperlight-dev/hyperlight-wasm#93

Merged

4 tasks

dblnz force-pushed the guest-tracing branch from 030a019 to 66af14f Compare July 9, 2025 14:20

dblnz marked this pull request as ready for review July 9, 2025 16:53

dblnz requested review from danbugs, ludfjig, devigned, syntactically, marosset, jprendes and simongdavies as code owners July 9, 2025 16:53

jsturtevant reviewed Jul 10, 2025

View reviewed changes

dblnz force-pushed the guest-tracing branch 3 times, most recently from baf50a8 to af68b04 Compare July 16, 2025 12:55

dblnz changed the title ~~[WIP] Enable guest tracing~~ Enable guest tracing Jul 16, 2025

dblnz force-pushed the guest-tracing branch 2 times, most recently from 6e23f9d to 61feafb Compare July 17, 2025 12:46

syntactically added 3 commits July 21, 2025 15:36

[hyperlight_host/exe] Allow load() to consume the exe_info

21cf19b

This will be useful in the near future, when it will allow transforming the exe_info into unwind information without an extra copy. Signed-off-by: Lucy Menon <[email protected]>

syntactically and others added 6 commits July 21, 2025 15:36

[hyperlight_host/trace] Add HV interface for reading trace registers

77c6ce7

This adds a new interface which tracing code can use to request the values of registers from the hypervisor supervising a sandbox. Signed-off-by: Lucy Menon <[email protected]>

[hyperlight_host/trace] Support collecting guest stacktraces

f5a8084

Signed-off-by: Lucy Menon <[email protected]> Signed-off-by: Doru Blânzeanu <[email protected]>

allow dead code for unused functions triggered by previous commit

e027582

Signed-off-by: Doru Blânzeanu <[email protected]>

Add trace support for recording memory allocations and frees

d26ccba

This allows for producing profiles of memory usage. Signed-off-by: Lucy Menon <[email protected]> Signed-off-by: Doru Blânzeanu <[email protected]>

Add basic utility for dumping logs and memory statistics from traces

7cc9a7a

Signed-off-by: Lucy Menon <[email protected]>

add license header to trace_dump

5d74e19

Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz force-pushed the guest-tracing branch from 61feafb to 11b4085 Compare July 21, 2025 12:42

syntactically reviewed Jul 21, 2025

View reviewed changes

dblnz force-pushed the guest-tracing branch from 11b4085 to 60bb45c Compare July 22, 2025 16:33

dblnz mentioned this pull request Jul 22, 2025

Improve guest tracing #723

Open

syntactically previously approved these changes Jul 22, 2025

View reviewed changes

src/hyperlight_guest_tracing/src/lib.rs Show resolved Hide resolved

dblnz added 7 commits July 23, 2025 14:17

Fix clippy warnings for unrelated work

407a2f4

Signed-off-by: Doru Blânzeanu <[email protected]>

Update sample guests to accept features that enable tracing

4ac82da

- Update CI to test the tracing functionality - Add features for the Justfile to be able to build guests with features Signed-off-by: Doru Blânzeanu <[email protected]>

Update utility for dumping logs to support the traces

593becc

Signed-off-by: Doru Blânzeanu <[email protected]>

Add documentation on how to use the tracing functionality

26a8954

Signed-off-by: Doru Blânzeanu <[email protected]>

dblnz dismissed syntactically’s stale review via 26a8954 July 23, 2025 11:30

dblnz force-pushed the guest-tracing branch from 60bb45c to 26a8954 Compare July 23, 2025 11:30

syntactically approved these changes Jul 23, 2025

View reviewed changes

dblnz enabled auto-merge (rebase) July 23, 2025 12:08

auto-merge was automatically disabled July 23, 2025 12:09
Base branch requires signed commits

dblnz merged commit 26a8954 into hyperlight-dev:main Jul 23, 2025
33 checks passed

dblnz deleted the guest-tracing branch July 23, 2025 12:11

dblnz mentioned this pull request Jul 23, 2025

Profile how much time is spent in wasmtime vs hyperlight_guest vs hyperlight_host #669

Open

Enable guest tracing #695

Enable guest tracing #695

Uh oh!

Conversation

dblnz commented Jul 7, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

How it works

Results

TODO

Uh oh!

dblnz commented Jul 9, 2025

Uh oh!

syntactically commented Jul 9, 2025

Uh oh!

jsturtevant left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

syntactically left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

dblnz commented Jul 22, 2025

Uh oh!

syntactically left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

syntactically left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

dblnz commented Jul 7, 2025 •

edited

Loading